search

elixir-lsp / elixir-ls

A frontend-independent IDE "smartness" server for Elixir. Implements the "Language Server Protocol" standard and provides debugger support via the "Debug Adapter Protocol"
https://elixir-lsp.github.io/elixir-ls/
Apache License 2.0
1.5k stars 198 forks source link

Debugger does not work on Elixir 1.10.0-1.10.2 #158

Closed hexpunk closed 4 years ago

hexpunk commented 4 years ago

Environment

Troubleshooting

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 commented 4 years ago

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 https://github.com/elixir-lang/elixir/pull/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 commented 4 years ago

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 commented 4 years ago

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

hexpunk commented 4 years ago

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

hexpunk commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

hexpunk commented 4 years ago

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 commented 4 years ago

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

axelson commented 4 years ago

@JayAndCatchFire et. al. Elixir 1.10.3 is now released :tada:! 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 commented 4 years ago

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 commented 4 years ago

@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 commented 4 years ago

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 commented 4 years ago

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. 🤷

81601454-84c07300-9390-11ea-84c0-e97adf449a75

axelson commented 4 years ago

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 commented 4 years ago

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 commented 3 years ago

@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.