Debugger does not work on Elixir 1.10.0-1.10.2

[hexpunk]

Environment

• Elixir & Erlang versions (elixir --version):

Erlang/OTP 22 [erts-10.6.4] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [hipe] [dtrace]

Elixir 1.10.2 (compiled with Erlang/OTP 22)

• Operating system:

System Version: macOS 10.15.3 (19D76)
Kernel Version: Darwin 19.3.0

• Editor or IDE name (e.g. Emacs/VSCode): VSCode
• LSP Client name:
• If using VSCode, are you using "ElixirLS Fork: Elixir support and debugger" (note that it has "Fork" in the name)? Yes

Troubleshooting

• Restart your editor (which will restart ElixirLS) sometimes fixes issues
• Stop your editor, remove the entire .elixir_ls directory, then restart your editor
  • NOTE: This will cause you to have to re-run the entire dialyzer build

Report

No matter what I do, I can't seem to get the debugger to act the same as when I run mix phx.server on the command line.

Here's my launch.json file:

{
    "version": "0.2.0",
    "configurations": [
        {
            "type": "mix_task",
            "name": "mix phx.server",
            "task": "phx.server",
            "request": "launch",
            "projectDir": "${workspaceRoot}",
            "startApps": true
        }
    ]
}

I have set startApps to true because if I don't then I get errors about opencensus.

My config/dev.exs has the following at the beginning, so the server starts on port 4000 and it kicks off npm start which runs my webpack-dev-server setup.

config :app_name, AppNameWeb.Endpoint,
  http: [port: 4000],
  debug_errors: true,
  code_reloader: true,
  check_origin: false,
  watchers: [
    npm: ["start"]
  ]

config :app_name, AppNameWeb.Endpoint,
  live_reload: [
    patterns: [
      # ~r{priv/static/.*(js|css|png|jpeg|jpg|gif|svg)$},
      ~r{lib/app_name_web/views/.*(ex)$},
      ~r{lib/app_name_web/templates/.*(eex)$},
      ~r{lib/app_name_web/live/.*(ex)$}
    ]
  ]

However, when I run the debugger, NPM doesn't seem to get started and no server ever seems to come up on port 4000. I know that config/dev.exs is being run because when I add a IO.inspect line at the top, I see my message printed in the Debug Console in VSCode. If I place a IO.inspect line beneath it, that gets printed as well, so I know nothing is erroring out from that config call.

I also always get errors related to my Oban and TelemetryMetricsPrometheus setup.

** (UndefinedFunctionError) function DBConnection.past_event/3 is undefined or private
    (db_connection 2.2.1) DBConnection.past_event(nil, :checkin, -576460721230932000)
    (db_connection 2.2.1) lib/db_connection.ex:1037: DBConnection.checkout/3
    (db_connection 2.2.1) lib/db_connection.ex:711: DBConnection.run/3
    (stdlib 3.11.2) gen_server.erl:637: :gen_server.try_dispatch/4
    (stdlib 3.11.2) gen_server.erl:711: :gen_server.handle_msg/6
    (stdlib 3.11.2) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: :poll
State: %Oban.Queue.Producer.State{circuit: :enabled, conf: %Oban.Config{beats_maxage: 300, circuit_backoff: 30000, crontab: [{%Oban.Crontab.Cron{days: [:*], hours: [:*], minutes: [:*], months: [:*], weekdays: [:*]}, AppName.ThirdParty.Sync, []}, {%Oban.Crontab.Cron{days: [:*], hours: [:*], minutes: [0, 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55], months: [:*], weekdays: [:*]}, AppName.DataProcessing.Runner, [args: %{check: true}]}], dispatch_cooldown: 5, name: Oban, node: "FR-A013", poll_interval: 1000, prefix: "public", prune: {:maxage, 259200}, prune_interval: 60000, prune_limit: 5000, queues: [default: 10, conversion: 10, processing: 10, third_party_sync: 10], repo: AppName.Repo, rescue_after: 60, rescue_interval: 60000, shutdown_grace_period: 15000, timezone: "Etc/UTC", verbose: false}, cooldown_ref: nil, dispatched_at: -576460720228, foreman: Oban.Queue.Conversion.Foreman, limit: 10, name: Oban.Queue.Conversion.Producer, nonce: "uhdfl0ju", paused: false, poll_ref: #Reference<0.1730123617.4046716929.79534>, queue: "conversion", rescue_ref: #Reference<0.1730123617.4046716929.44865>, running: %{}, started_at: ~U[2020-03-20 22:29:17.081743Z]}
2020-03-20T22:29:35.304Z [ERROR] GenServer Oban.Queue.Default.Producer terminating
** (UndefinedFunctionError) function DBConnection.past_event/3 is undefined or private
    (db_connection 2.2.1) DBConnection.past_event(nil, :checkin, -576460721231309000)
    (db_connection 2.2.1) lib/db_connection.ex:1037: DBConnection.checkout/3
    (db_connection 2.2.1) lib/db_connection.ex:711: DBConnection.run/3
    (stdlib 3.11.2) gen_server.erl:637: :gen_server.try_dispatch/4
    (stdlib 3.11.2) gen_server.erl:711: :gen_server.handle_msg/6
    (stdlib 3.11.2) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: :poll
State: %Oban.Queue.Producer.State{circuit: :enabled, conf: %Oban.Config{beats_maxage: 300, circuit_backoff: 30000, crontab: [{%Oban.Crontab.Cron{days: [:*], hours: [:*], minutes: [:*], months: [:*], weekdays: [:*]}, AppName.ThirdParty.Sync, []}, {%Oban.Crontab.Cron{days: [:*], hours: [:*], minutes: [0, 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55], months: [:*], weekdays: [:*]}, AppName.DataProcessing.Runner, [args: %{check: true}]}], dispatch_cooldown: 5, name: Oban, node: "FR-A013", poll_interval: 1000, prefix: "public", prune: {:maxage, 259200}, prune_interval: 60000, prune_limit: 5000, queues: [default: 10, conversion: 10, processing: 10, third_party_sync: 10], repo: AppName.Repo, rescue_after: 60, rescue_interval: 60000, shutdown_grace_period: 15000, timezone: "Etc/UTC", verbose: false}, cooldown_ref: nil, dispatched_at: -576460720228, foreman: Oban.Queue.Default.Foreman, limit: 10, name: Oban.Queue.Default.Producer, nonce: "e02gifo1", paused: false, poll_ref: #Reference<0.1730123617.4046716930.34527>, queue: "default", rescue_ref: #Reference<0.1730123617.4046716929.44850>, running: %{}, started_at: ~U[2020-03-20 22:29:17.077948Z]}
2020-03-20T22:29:35.304Z [ERROR] GenServer Oban.Queue.ThirdPartySync.Producer terminating
** (UndefinedFunctionError) function DBConnection.past_event/3 is undefined or private
    (db_connection 2.2.1) DBConnection.past_event(nil, :checkin, -576460722273411000)
    (db_connection 2.2.1) lib/db_connection.ex:1037: DBConnection.checkout/3
    (db_connection 2.2.1) lib/db_connection.ex:711: DBConnection.run/3
    (stdlib 3.11.2) gen_server.erl:637: :gen_server.try_dispatch/4
    (stdlib 3.11.2) gen_server.erl:711: :gen_server.handle_msg/6
    (stdlib 3.11.2) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: :poll
State: %Oban.Queue.Producer.State{circuit: :enabled, conf: %Oban.Config{beats_maxage: 300, circuit_backoff: 30000, crontab: [{%Oban.Crontab.Cron{days: [:*], hours: [:*], minutes: [:*], months: [:*], weekdays: [:*]}, AppName.ThirdParty.Sync, []}, {%Oban.Crontab.Cron{days: [:*], hours: [:*], minutes: [0, 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55], months: [:*], weekdays: [:*]}, AppName.DataProcessing.Runner, [args: %{check: true}]}], dispatch_cooldown: 5, name: Oban, node: "FR-A013", poll_interval: 1000, prefix: "public", prune: {:maxage, 259200}, prune_interval: 60000, prune_limit: 5000, queues: [default: 10, conversion: 10, processing: 10, third_party_sync: 10], repo: AppName.Repo, rescue_after: 60, rescue_interval: 60000, shutdown_grace_period: 15000, timezone: "Etc/UTC", verbose: false}, cooldown_ref: nil, dispatched_at: -576460720228, foreman: Oban.Queue.ThirdPartySync.Foreman, limit: 10, name: Oban.Queue.ThirdPartySync.Producer, nonce: "2m4fcr3p", paused: false, poll_ref: #Reference<0.1730123617.4046716931.35804>, queue: "third_party_sync", rescue_ref: #Reference<0.1730123617.4046716929.44856>, running: %{}, started_at: ~U[2020-03-20 22:29:17.082110Z]}
2020-03-20T22:29:35.304Z [ERROR] GenServer Oban.Queue.Processing.Producer terminating
** (UndefinedFunctionError) function DBConnection.past_event/3 is undefined or private
    (db_connection 2.2.1) DBConnection.past_event(nil, :checkin, -576460722273383000)
    (db_connection 2.2.1) lib/db_connection.ex:1037: DBConnection.checkout/3
    (db_connection 2.2.1) lib/db_connection.ex:711: DBConnection.run/3
    (stdlib 3.11.2) gen_server.erl:637: :gen_server.try_dispatch/4
    (stdlib 3.11.2) gen_server.erl:711: :gen_server.handle_msg/6
    (stdlib 3.11.2) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: :poll
State: %Oban.Queue.Producer.State{circuit: :enabled, conf: %Oban.Config{beats_maxage: 300, circuit_backoff: 30000, crontab: [{%Oban.Crontab.Cron{days: [:*], hours: [:*], minutes: [:*], months: [:*], weekdays: [:*]}, AppName.ThirdParty.Sync, []}, {%Oban.Crontab.Cron{days: [:*], hours: [:*], minutes: [0, 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55], months: [:*], weekdays: [:*]}, AppName.DataProcessing.Runner, [args: %{check: true}]}], dispatch_cooldown: 5, name: Oban, node: "FR-A013", poll_interval: 1000, prefix: "public", prune: {:maxage, 259200}, prune_interval: 60000, prune_limit: 5000, queues: [default: 10, conversion: 10, processing: 10, third_party_sync: 10], repo: AppName.Repo, rescue_after: 60, rescue_interval: 60000, shutdown_grace_period: 15000, timezone: "Etc/UTC", verbose: false}, cooldown_ref: nil, dispatched_at: -576460720228, foreman: Oban.Queue.Processing.Foreman, limit: 10, name: Oban.Queue.Processing.Producer, nonce: "355krvf4", paused: false, poll_ref: #Reference<0.1730123617.4046716931.35805>, queue: "processing", rescue_ref: #Reference<0.1730123617.4046716930.27017>, running: %{}, started_at: ~U[2020-03-20 22:29:17.081962Z]}
2020-03-20T22:29:35.322Z [INFO] Postgrex.Protocol (#PID<0.2952.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.3132.0> exited
2020-03-20T22:29:35.323Z [INFO] Postgrex.Protocol (#PID<0.2955.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.3128.0> exited
2020-03-20T22:29:35.323Z [INFO] Postgrex.Protocol (#PID<0.2951.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.3124.0> exited
2020-03-20T22:29:35.324Z [INFO] Postgrex.Protocol (#PID<0.2953.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.3120.0> exited
2020-03-20T22:29:51.004Z [ERROR] Handler {TelemetryMetricsPrometheus.Core.EventHandler, #PID<0.3005.0>, [:vm, :memory, :total]} has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

2020-03-20T22:29:51.004Z [ERROR] Handler {TelemetryMetricsPrometheus.Core.EventHandler, #PID<0.3005.0>, [:vm, :total_run_queue_lengths, :total]} has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

2020-03-20T22:29:51.004Z [ERROR] Handler {TelemetryMetricsPrometheus.Core.EventHandler, #PID<0.3005.0>, [:vm, :total_run_queue_lengths, :cpu]} has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

2020-03-20T22:29:51.005Z [ERROR] Handler {TelemetryMetricsPrometheus.Core.EventHandler, #PID<0.3005.0>, [:vm, :total_run_queue_lengths, :io]} has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

2020-03-20T22:30:17.160Z [ERROR] Handler "oban-default-logger" has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

2020-03-20T22:30:17.160Z [ERROR] Handler "oban-default-logger" has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

2020-03-20T22:30:17.196Z [ERROR] Handler {TelemetryMetricsPrometheus.Core.EventHandler, #PID<0.3005.0>, [:oban, :success, :duration]} has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

I've tried killing the code that sets up the telemetry library and while it stops these errors from happening, it doesn't fix the underlying problem where the server never starts. Also, there's clearly something happening since the debugging sessions doesn't end with an error or anything like that. And I see various processes/tasks/agents/genservers/whatever running in the callstack pane in VSCode. I'm not sure what to do to set this up properly.

FWIW, I'm able to set up a new boilerplate project using phx_new that will cooperate with the debugger relatively fine, although I do get these errors in the console:

[error] Handler {Phoenix.Logger, [:phoenix, :endpoint, :start]} has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

[error] Handler {Phoenix.Logger, [:phoenix, :router_dispatch, :start]} has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

[error] Handler {Phoenix.Logger, [:phoenix, :endpoint, :stop]} has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

[axelson]

The debugger does not work on Elixir 1.10.0-1.10.2 (the fix has been merged upstream but we need to wait for elixir-lang/elixir#9864 to be released in 1.10.3). Will close this if a workaround can be found or Elixir 1.10.3 is released.

[hexpunk]

Thank you so much for the information. (I thought I was losing my mind.)

Does that mean the debugger works on the 1.9.x releases of Elixir? I might try downgrading if it means I can use the debugger.

[axelson]

Yes it should. I also might be able to prep a PR that will improve 1.10 support.

[hexpunk]

Why does the boilerplate project created with phx_new seemingly work with the debugger okay?

[hexpunk]

FWIW, I just tried running my app with Elixir 1.9.4, but there's code in my app that's using functions like compile_env! that were introduced in the Elixir 1.10.x branch, so I guess I'll just have to wait for the 1.10.3 release before I can use the debugger. 😢

[axelson]

Why does the boilerplate project created with phx_new seemingly work with the debugger okay?

I'm not sure quite what you're saying. I don't expect this to work on Elixir 1.10

[hexpunk]

I was able to spin up a basic "hello" project using phx_new running on Elixir 1.10.2 and I was able to get the debugger to attach to it and break at breakpoints.

[axelson]

Is there a more complicated project that reproduces the error that you could share?

[hexpunk]

Unfortunately, no. The one I'm having trouble with is my employer's code. I'll wait until the fixed version of Elixir comes out and if it still doesn't work, I'll dig deeper then.

[axelson]

FYI, changed the title and pinned this for better visibility until the next release of elixir.

[axelson]

@jayandcatchfire et. al. Elixir 1.10.3 is now released 🎉! So I've added a warning in #221 (which will be included in 0.3.4 eventually) that warns you when debugging if you are running Elixir 1.10.0 - 1.10.2.

[hexpunk]

FWIW, I've just now tried this using Elixir 1.10.3 and I'm seeing the exact same issue that I originally reported.

[axelson]

@jayandcatchfire I'm looking at your error log in more detail and it looks like you were encountering an error unrelated to the version of elixir being run. Do you know what mix env the code is running under (by default it is often test)? Do you have any dependencies that aren't used in the test environment?

[hexpunk]

It should be running under the dev mix env, but I'll adjust my config to make it explicit and try again, just to be sure.

[hexpunk]

I tried adding the MIX_ENV environment variable to the launch config, but it still acts the same way. Something is running, but not the local server. 🤷

[axelson]

Are you not getting the function DBConnection.past_event/3 is undefined or private errors any more? Can you post a full log of the debug console output and the ElixirLS output?

[hexpunk]

That's correct. I'm not getting the function DBConnection.past_event/3 is undefined or private errors anymore.

I checked the ElixirLS output and it doesn't output anything after I start the debugger.

The debug console output is as follows (db table names edited because it's my employer's code base):

Erlang version: "22"
Compiling 149 files (.ex)
2020-05-20T19:00:08.733Z [DEBUG] QUERY OK source="table1" db=1.1ms decode=2.9ms queue=1.2ms
SELECT m0."id", m1."location_id" FROM "table1" AS m0 INNER JOIN "table1_locations" AS m1 ON m1."table1_id" = m0."id" []
2020-05-20T19:00:52.934Z [ERROR] Handler {TelemetryMetricsPrometheus.Core.EventHandler, #PID<0.1831.0>, [:vm, :memory, :total]} has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

2020-05-20T19:00:52.935Z [ERROR] Handler {TelemetryMetricsPrometheus.Core.EventHandler, #PID<0.1831.0>, [:vm, :total_run_queue_lengths, :total]} has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

2020-05-20T19:00:52.935Z [ERROR] Handler {TelemetryMetricsPrometheus.Core.EventHandler, #PID<0.1831.0>, [:vm, :total_run_queue_lengths, :cpu]} has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

2020-05-20T19:00:52.936Z [ERROR] Handler {TelemetryMetricsPrometheus.Core.EventHandler, #PID<0.1831.0>, [:vm, :total_run_queue_lengths, :io]} has failed and has been detached. Class=:error
Reason=:undef
Stacktrace=[]

After that, it just sits there.

[lukaszsamson]

@jayandcatchfire I noticed a similar problem with debugging phoenix app - when "startApps": true was set in my launch config, the debugger would start but the http server would not.
Besides, telemetry handlers that are a private function does not work i interpreted mode. It's best to just add them to exclude list.