Debugger fails initialization on demo phoenix project

[azazel75]

I tried the debugger with one of my projects and it seemed to work well at
first, but then when I setup a breakpoint the debugger process ended because an
exception was raised roughly after 60 seconds. That smelled strange so I
decided to try the debugger on the output of a basic mix phx.new hello_world
project just to see if my setup worked. That failed with another error, which
I'm now reporting here. I've reported something
similar
on the forum an year ago but not having received any feedback I decided to write
here. when I run the debugger with a configuration where the relevant settings
are just "task": "phx.server" the log is the following:

Started ElixirLS debugger v0.6.2
Elixir version: "1.10.4 (compiled with Erlang/OTP 22)"
Erlang version: "22"
ElixirLS compiled with Elixir 1.10.4 and erlang 22
(Debugger) Initialization failed because an exception was raised:
    ** (RuntimeError) could not lookup Ecto repo HelloWorld.Repo because it was not started or it does not exist
        Elixir.Ecto.Repo.Registry.erl:19: Ecto.Repo.Registry.lookup/1
        Elixir.Ecto.Adapter.erl:127: Ecto.Adapter.lookup_meta/1
        Elixir.Ecto.Adapters.SQL.Sandbox.erl:538: Ecto.Adapters.SQL.Sandbox.lookup_meta!/1
        Elixir.Ecto.Adapters.SQL.Sandbox.erl:435: Ecto.Adapters.SQL.Sandbox.mode/2

03:35:15.217 [error] Process #PID<0.117.0> raised an exception
** (RuntimeError) could not lookup Ecto repo HelloWorld.Repo because it was not started or it does not exist
    Elixir.Ecto.Repo.Registry.erl:19: Ecto.Repo.Registry.lookup/1
    Elixir.Ecto.Adapter.erl:127: Ecto.Adapter.lookup_meta/1
    Elixir.Ecto.Adapters.SQL.Sandbox.erl:538: Ecto.Adapters.SQL.Sandbox.lookup_meta!/1
    Elixir.Ecto.Adapters.SQL.Sandbox.erl:435: Ecto.Adapters.SQL.Sandbox.mode/2

... and if I add "startApps": true to the settingd the log is slightly different:

Started ElixirLS debugger v0.6.2
Elixir version: "1.10.4 (compiled with Erlang/OTP 22)"
Erlang version: "22"
ElixirLS compiled with Elixir 1.10.4 and erlang 22
(Debugger) Initialization failed because an exception was raised:
    ** (RuntimeError) cannot invoke sandbox operation with pool DBConnection.ConnectionPool.
To use the SQL Sandbox, configure your repository pool as:

    pool: Ecto.Adapters.SQL.Sandbox

        (ecto_sql 3.5.3) Elixir.Ecto.Adapters.SQL.Sandbox.erl:541: Ecto.Adapters.SQL.Sandbox.lookup_meta!/1
        (ecto_sql 3.5.3) Elixir.Ecto.Adapters.SQL.Sandbox.erl:435: Ecto.Adapters.SQL.Sandbox.mode/2

Talking with vhf on the #elixir-lang channel he told me that the
instrumentation adds computational overhead and this messes the things with the
application bootstrap. I'm no Elixir expert but looking at the debugger's code
I see that it calls Mix.Task.run() multiple times, but again looking at the
implementation of that it doesn't seem to offer any kind of coordination between
the process that calls it and when the task is really executed so the calling
process (the debugger server) just goes on with the initialization without
really wait for those tasks to be executed. Am I wrong? Could it be the
culprit? What can be done to alleviate the symptom?

(The db was previously initialized and the mix phx.server command from the
shell worked as expected)

I'm coming from Python and I must say that the debugging experience in Elixir
could really improve with an usable debugger. Don't get me wrong,Iex.pry()
helps but without a chance of stepping through the code you can use it almost
just to confirm your intuition of where and what is causing the bug.

Environment

• Elixir & Erlang versions (elixir --version): Elixir 1.10.4 (compiled with
  Erlang/OTP 22)
• Operating system: NixOS GNU/Linux
• Editor or IDE name (e.g. Emacs/VSCode): GNU Emacs 27.1 with Doom Emacs configuration
• Editor Plugin/LSP Client name: emacs-lsp/dap-mode

ElixirLS is at commit a696d94f5a7b9d9d5323d79342bc206a26cf14bb

Troubleshooting

• Restart your editor (which will restart ElixirLS) sometimes fixes issues
• Stop your editor, remove the entire .elixir_ls directory, then restart your editor

[lukaszsamson]

I'm unable to reproduce this issue on macOS with the following launch config

{
    "type": "mix_task",
    "name": "mix phx.server",
    "request": "launch",
    "task": "phx.server",
    "projectDir": "${workspaceRoot}"
}

Started ElixirLS debugger v0.6.2
Elixir version: "1.11.3 (compiled with Erlang/OTP 23)"
Erlang version: "23"
ElixirLS compiled with Elixir 1.8.2 and erlang 21
[info] Running MyAppWeb.Endpoint with cowboy 2.8.0 at 0.0.0.0:4000 (http)
[info] Access MyAppWeb.Endpoint at http://localhost:4000

webpack is watching the files…

Can you post a repo that reproduces it?

[azazel75]

Of course, here it is: https://github.com/azazel75/phoenix_elixirls_debugger_failure

[lukaszsamson]

Sorry, I'm not able to reproduce. Since you not posted a launch config I used the one from my previous post. Please verify that your launch config is valid. Especially check if "startApps": true is not set as it prevents phoenix from starting properly.

[azazel75]

Hi @lukaszsamson, I don't know how to test your JSON configuration using the
debugger.sh executable, but this is the template configuration that I use with
emacs' dap-mode:

(dap-register-debug-template
  "Elixir::Phoenix"
  (list :type "Elixir"
        :task "phx.server"
        :taskArgs nil
        :request "launch"
        :program nil
        :name "Elixir::Phoenix"))

so no startApps: true.. The rest of the missing keys are filled-in by dap-mode using the following function:

(defun dap-elixir--populate-start-file-args (conf)
  "Populate CONF with the required arguments."
  (-> conf
      (dap--put-if-absent :dap-server-path '("debugger.sh"))
      (dap--put-if-absent :type "mix_task")
      (dap--put-if-absent :name "mix test")
      (dap--put-if-absent :request "launch")
      (dap--put-if-absent :task "test")
      (dap--put-if-absent :taskArgs (list "--trace"))
      (dap--put-if-absent :projectDir (lsp-find-session-folder (lsp-session) (buffer-file-name)))
      (dap--put-if-absent :cwd (lsp-find-session-folder (lsp-session) (buffer-file-name)))
      (dap--put-if-absent :requireFiles (list
                                         "test/**/test_helper.exs"
                                         "test/**/*_test.exs"))))

I hope that this is understandable even if this is emacs lisp code. In that
function the buffer-file-name symbol contains the name of the Elixir file
opened that the user is reading when the debug command is executed. That said I
think that the final configuration matches what you posted before.

[lukaszsamson]

OK @azazel75, I was able to reproduce it when I added

"requireFiles": [
    "test/**/test_helper.exs",
    "test/**/*_test.exs"
]

Your config is wrong - you require test files that try to init a sandboxed repo when the app is not yet started. You need to pass an empty list here.

I'm not sure about other settings but

• taskArgs seem wrong - won't dap--put-if-absent overwrite nil with list "--trace"?
• program is not a known setting
• type should be mix_task

[azazel75]

You're right, dap--put-if-absent treats entries with nil values as if they where missing, silly me... I just tried. Redefining the dap-elixir--populate-start-file-args function as:

(defun dap-elixir--populate-start-file-args (conf)
  "Populate CONF with the required arguments."
  (-> conf
      (dap--put-if-absent :dap-server-path '("debugger.sh"))
      (dap--put-if-absent :type "mix_task")
      (dap--put-if-absent :name "mix test")
      (dap--put-if-absent :request "launch")
      (dap--put-if-absent :task "test")
      (dap--put-if-absent :projectDir (lsp-find-session-folder (lsp-session) (buffer-file-name)))
      (dap--put-if-absent :cwd (lsp-find-session-folder (lsp-session) (buffer-file-name)))))

Does the trick and the launch is effective, thanks @lukaszsamson and ... silly me!

That brings me to the other error I'm experiencing, tell me if it's better that I move to another issue.

If I now set a breakpoing to page_controller.ex at line 5 and I visit the page with a browser, the debugger stops at that line, but if I wait more or less one minute the debugger process crashes. This is the log:

Started ElixirLS debugger v0.6.2
Elixir version: "1.10.4 (compiled with Erlang/OTP 22)"
Erlang version: "22"
ElixirLS compiled with Elixir 1.10.4 and erlang 22
[info] Running HelloWorldWeb.Endpoint with cowboy 2.8.0 at 0.0.0.0:4000 (http)
[info] Access HelloWorldWeb.Endpoint at http://localhost:4000

webpack is watching the files…

[hardsource:3ac8a0a7] Using 1 MB of disk space.
[hardsource:3ac8a0a7] Tracking node dependencies with: package-lock.json.
[hardsource:3ac8a0a7] Reading from cache 3ac8a0a7...
Hash: 768599c12375360061b7
Version: webpack 4.41.5
Time: 133ms
Built at: 07/01/2021 16:18:02
                Asset       Size  Chunks             Chunk Names
       ../css/app.css   10.7 KiB     app  [emitted]  app
       ../favicon.ico   1.23 KiB          [emitted]  
../images/phoenix.png   13.6 KiB          [emitted]  
        ../robots.txt  202 bytes          [emitted]  
               app.js   13.5 KiB     app  [emitted]  app
Entrypoint app = ../css/app.css app.js
[0] multi ./js/app.js 28 bytes {app} [built]
    + 5 hidden modules
[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=[]

(Debugger) Terminating because an exception was raised:
    ** (MatchError) no match of right hand side value: nil
        (elixir_ls_debugger 0.6.2) lib/debugger/server.ex:291: ElixirLS.Debugger.Server.handle_request/2
        (elixir_ls_debugger 0.6.2) lib/debugger/server.ex:90: ElixirLS.Debugger.Server.handle_cast/2
        (stdlib 3.12) gen_server.erl:637: :gen_server.try_dispatch/4
        (stdlib 3.12) gen_server.erl:711: :gen_server.handle_msg/6
        (stdlib 3.12) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
ElixirLS debugger has crashed
[error] GenServer ElixirLS.Debugger.Server terminating
** (MatchError) no match of right hand side value: nil
    (elixir_ls_debugger 0.6.2) lib/debugger/server.ex:291: ElixirLS.Debugger.Server.handle_request/2
    (elixir_ls_debugger 0.6.2) lib/debugger/server.ex:90: ElixirLS.Debugger.Server.handle_cast/2
    (stdlib 3.12) gen_server.erl:637: :gen_server.try_dispatch/4
    (stdlib 3.12) gen_server.erl:711: :gen_server.handle_msg/6
    (stdlib 3.12) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: {:"$gen_cast", {:receive_packet, %{"arguments" => %{"frameId" => 2}, "command" => "scopes", "seq" => 11, "type" => "request"}}}
State: %ElixirLS.Debugger.Server{breakpoints: %{"/tmp/hello_world/lib/hello_world_web/controllers/page_controller.ex" => [{HelloWorldWeb.PageController, 5}]}, client_info: %{"adapterID" => "Elixir", "clientID" => "vscode", "clientName" => "Visual Studio Code", "columnsStartAt1" => true, "linesStartAt1" => true, "locale" => "en-us", "pathFormat" => "path", "supportsRunInTerminalRequest" => true, "supportsVariablePaging" => true, "supportsVariableType" => true}, config: %{"cwd" => "/tmp/hello_world", "name" => "Elixir::Phoenix<10>", "program" => nil, "projectDir" => "/tmp/hello_world", "request" => "launch", "task" => "phx.server", "taskArgs" => nil, "type" => "Elixir"}, next_id: 24, output: ElixirLS.Debugger.Output, paused_processes: %{#PID<0.1338.0> => %ElixirLS.Debugger.Server.PausedProcess{frames: %{16 => %ElixirLS.Debugger.Stacktrace.Frame{args: [%Plug.Conn{adapter: {Plug.Cowboy.Conn, :...}, assigns: %{}, before_send: [#Function<33.103228614/1 in :dbg_ieval.expr/3>, #Function<33.103228614/1 in :dbg_ieval.expr/3>], body_params: %{}, cookies: %{"_bolgia_key" => "SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYbjUtVXZZY2YwZjFOUHBMdmk4YjVfeXNG.Q8tKVpXGZnIO-r8VPA9b6AhslXZv6QwGDsSeZFpBcio", "_hello_world_key" => "SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYVUMxTlVvRG9GY1V0QkZyanAzT01XcXF4.TK47nkYvBBd_jjdmBzfkIdBccPFau4K5FTHYHosPfzU"}, halted: false, host: "localhost", method: "GET", owner: #PID<0.1338.0>, params: %{}, path_info: [], path_params: %{}, port: 4000, private: %{HelloWorldWeb.Router => {[], %{}}, :phoenix_endpoint => HelloWorldWeb.Endpoint, :phoenix_request_logger => {"request_logger", "request_logger"}, :phoenix_router => HelloWorldWeb.Router, :plug_session_fetch => #Function<33.103228614/1 in :dbg_ieval.expr/3>}, query_params: %{}, query_string: "", remote_ip: {127, 0, 0, 1}, req_cookies: %{"_bolgia_key" => "SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYbjUtVXZZY2YwZjFOUHBMdmk4YjVfeXNG.Q8tKVpXGZnIO-r8VPA9b6AhslXZv6QwGDsSeZFpBcio", "_hello_world_key" => "SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYVUMxTlVvRG9GY1V0QkZyanAzT01XcXF4.TK47nkYvBBd_jjdmBzfkIdBccPFau4K5FTHYHosPfzU"}, req_headers: [{"accept", "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8"}, {"accept-encoding", "gzip, deflate"}, {"accept-language", "it,en;q=0.7,en-US;q=0.3"}, {"cache-control", "max-age=0"}, {"connection", "keep-alive"}, {"cookie", "_bolgia_key=SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYbjUtVXZZY2YwZjFOUHBMdmk4YjVfeXNG.Q8tKVpXGZnIO-r8VPA9b6AhslXZv6QwGDsSeZFpBcio; _hello_world_key=SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYVUMxTlVvRG9GY1V0QkZyanAzT01XcXF4.TK47nkYvBBd_jjdmBzfkIdBccPFau4K5FTHYHosPfzU"}, {"dnt", "1"}, {"host", "localhost:4000"}, {"sec-gpc", "1"}, {"upgrade-insecure-requests", "1"}, {"user-agent", "Mozilla/5.0 (Windows NT 10.0; rv:78.0) Gecko/20100101 Firefox/78.0"}], request_path: "/", resp_body: nil, resp_cookies: %{}, resp_headers: [{"cache-control", "max-age=0, private, must-revalidate"}, {"x-request-id", "Flf8OOCTPs9cm2cAAAFD"}], scheme: :http, script_name: [], secret_key_base: :..., state: :unset, status: nil}, {%{conn: nil, log: :debug, path_params: %{}, pipe_through: [:browser], plug: HelloWorldWeb.PageController, plug_opts: :index, route: "/"}, #Function<39.103228614/2 in :dbg_ieval.expr/3>, #Function<33.103228614/1 in :dbg_ieval.expr/3>, {HelloWorldWeb.PageController, :index}}], bindings: %{___STACKTRACE__@1: [], _conn@1: %Plug.Conn{adapter: {Plug.Cowboy.Conn, :...}, assigns: %{}, before_send: [#Function<33.103228614/1 in :dbg_ieval.expr/3>, #Function<33.103228614/1 in :dbg_ieval.expr/3>], body_params: %{}, cookies: %{"_bolgia_key" => "SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYbjUtVXZZY2YwZjFOUHBMdmk4YjVfeXNG.Q8tKVpXGZnIO-r8VPA9b6AhslXZv6QwGDsSeZFpBcio", "_hello_world_key" => "SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYVUMxTlVvRG9GY1V0QkZyanAzT01XcXF4.TK47nkYvBBd_jjdmBzfkIdBccPFau4K5FTHYHosPfzU"}, halted: false, host: "localhost", method: "GET", owner: #PID<0.1338.0>, params: %{}, path_info: [], path_params: %{}, port: 4000, private: %{HelloWorldWeb.Router => {[], %{}}, :phoenix_endpoint => HelloWorldWeb.Endpoint, :phoenix_request_logger => {"request_logger", "request_logger"}, :phoenix_router => HelloWorldWeb.Router, :plug_session_fetch => #Function<33.103228614/1 in :dbg_ieval.expr/3>}, query_params: %{}, query_string: "", remote_ip: {127, 0, 0, 1}, req_cookies: %{"_bolgia_key" => "SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYbjUtVXZZY2YwZjFOUHBMdmk4YjVfeXNG.Q8tKVpXGZnIO-r8VPA9b6AhslXZv6QwGDsSeZFpBcio", "_hello_world_key" => "SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYVUMxTlVvRG9GY1V0QkZyanAzT01XcXF4.TK47nkYvBBd_jjdmBzfkIdBccPFau4K5FTHYHosPfzU"}, req_headers: [{"accept", "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8"}, {"accept-encoding", "gzip, deflate"}, {"accept-language", "it,en;q=0.7,en-US;q=0.3"}, {"cache-control", "max-age=0"}, {"connection", "keep-alive"}, {"cookie", "_bolgia_key=SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYbjUtVXZZY2YwZjFOUHBMdmk4YjVfeXNG.Q8tKVpXGZnIO-r8VPA9b6AhslXZv6QwGDsSeZFpBcio; _hello_world_key=SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYVUMxTlVvRG9GY1V0QkZyanAzT01XcXF4.TK47nkYvBBd_jjdmBzfkIdBccPFau4K5FTHYHosPfzU"}, {"dnt", "1"}, {"host", "localhost:4000"}, {"sec-gpc", "1"}, {"upgrade-insecure-requests", "1"}, {"user-agent", "Mozilla/5.0 (Windows NT 10.0; rv:78.0) Gecko/20100101 Firefox/78.0"}], request_path: "/", resp_body: nil, resp_cookies: %{}, resp_headers: [{"cache-control", "max-age=0, private, must-revalidate"}, {"x-request-id", "Flf8OOCTPs9cm2cAAAFD"}], scheme: :http, script_name: [], secret_key_base: :..., state: :unset, status: nil}, _conn@2: %Plug.Conn{adapter: {Plug.Cowboy.Conn, :...}, assigns: %{}, before_send: [#Function<33.103228614/1 in :dbg_ieval.expr/3>, #Function<33.103228614/1 in :dbg_ieval.expr/3>], body_params: %{}, cookies: %{"_bolgia_key" => "SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYbjUtVXZZY2YwZjFOUHBMdmk4YjVfeXNG.Q8tKVpXGZnIO-r8VPA9b6AhslXZv6QwGDsSeZFpBcio", "_hello_world_key" => "SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYVUMxTlVvRG9GY1V0QkZyanAzT01XcXF4.TK47nkYvBBd_jjdmBzfkIdBccPFau4K5FTHYHosPfzU"}, halted: false, host: "localhost", method: "GET", owner: #PID<0.1338.0>, params: %{}, path_info: [], path_params: %{}, port: 4000, private: %{HelloWorldWeb.Router => {[], %{}}, :phoenix_endpoint => HelloWorldWeb.Endpoint, :phoenix_request_logger => {"request_logger", "request_logger"}, :phoenix_router => HelloWorldWeb.Router, :plug_session_fetch => #Function<33.103228614/1 in :dbg_ieval.expr/3>}, query_params: %{}, query_string: "", remote_ip: {127, 0, 0, 1}, req_cookies: %{"_bolgia_key" => "SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYbjUtVXZZY2YwZjFOUHBMdmk4YjVfeXNG.Q8tKVpXGZnIO-r8VPA9b6AhslXZv6QwGDsSeZFpBcio", "_hello_world_key" => "SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYVUMxTlVvRG9GY1V0QkZyanAzT01XcXF4.TK47nkYvBBd_jjdmBzfkIdBccPFau4K5FTHYHosPfzU"}, req_headers: [{"accept", "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8"}, {"accept-encoding", "gzip, deflate"}, {"accept-language", "it,en;q=0.7,en-US;q=0.3"}, {"cache-control", "max-age=0"}, {"connection", "keep-alive"}, {"cookie", "_bolgia_key=SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYbjUtVXZZY2YwZjFOUHBMdmk4YjVfeXNG.Q8tKVpXGZnIO-r8VPA9b6AhslXZv6QwGDsSeZFpBcio; _hello_world_key=SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYVUMxTlVvRG9GY1V0QkZyanAzT01XcXF4.TK47nkYvBBd_jjdmBzfkIdBccPFau4K5FTHYHosPfzU"}, {"dnt", "1"}, {"h (truncated)

This happens even when I'm stepping through the code. Is this an expected behaviour? Is it maybe the resulting of the browser closing the connection?

Thanks in advance for your patience

[lukaszsamson]

Good to hear you made it work @azazel75 .
I extracted the second error into a separate issue as it's not related to this one. As a temporary workaround you can try to increase cowboy request timeout.

[azazel75]

For anyone coming here, to increase the timeout i changed the line

https://github.com/azazel75/phoenix_elixirls_debugger_failure/blob/1960ebc2ce6fe82007a7c1499983ab6f08636dfa/config/dev.exs#L19

to

  http: [port: 4000, protocol_options: [idle_timeout: 300000]], 

to get a timeout of 5 minutes

[lukaszsamson]

While investigating #452 I noticed more issues #453 #454

[mjsommer]

Your config is wrong - you require test files that try to init a sandboxed repo when the app is not yet started. You need to pass an empty list here.

This advise is magic!! So many examples out there, present this as a requirement.