5

When I use IEx.pry or a breakpoint (via :int.break()), the interactive shell dies too quickly, and I only have ~10 seconds before I lose my session:

** (EXIT from #PID<0.606.0>) shell process exited with reason: shutdown

And 10 seconds isn’t enough to productively debug my code in the shell/debugger. My best guess is that there’s a default timeout in a :supervisor.child_spec that I need to override, but I’m not 100% sure.

This is what I’ve tried so far (and why they haven’t worked so far):

  • Increase the :shutdown parameter to :infinity in the child_specs to Supervisor.start_link() in MyApp.Application.
  • Updated the cowboy timeouts (idle_timeout, linger_timeout, request_timeout, shutdown_timeout) because Observer indicated that my request is a cowboy process. I don’t think it’s likely that it’s cowboy, though. If the default is 60s, I’m not even getting close to 60s.
  • Instead of using IEx.pry, I tried using the debugger (via :ni.break)
  • Just noting that I can’t use mix test --trace, which sets the timeout to :infinity. Since I’m trying to debug a non-test Endpoint action, this flag won't help.

How do people use the debugger/IEx.pry? (I'm coming from a Ruby/JS world, so I like to have some time to inspect the variables.) Are people just not encountering the 10s timeout like I am? Or is there some common configuration that I’m missing for my troubleshooting needs?

My Supervisor/child configs in application.ex:

Note the shutdown: :infinity configuration.

defmodule MyApp.Application do
  use Application

  def start(_type, _args) do
    children = [
      MyApp.Repo,
      {MyApp.Web.Endpoint, [shutdown: :infinity]},
      {Phoenix.PubSub, [name: MyApp.PubSub, adapter: Phoenix.PubSub.PG2]},
      {MyApp.Middleware.Ets.AnEtsThing, [name: MyApp.Middleware.Ets.AnEtsThing, table_name: :my_app_config_2]},
    ]
    opts = [strategy: :one_for_one, name: MyApp.Supervisor]
    Supervisor.start_link(children, opts)
  end

  def config_change(changed, _new, removed) do
    MyApp.Web.Endpoint.config_change(changed, removed)
    :ok
  end
end

My cowboy configs in dev.exs

config :my_app, MyApp.Web.Endpoint,
  http: [
    port: 4000,
    protocol_options: [
      request_timeout: 100_000_000,
      shutdown_timeout: 100_000_000,
      idle_timeout: 100_000_000,
      linger_timeout: 100_000_000,
    ]
  ]

Console inspection of Cowboy configs

This is just to confirm that I was configuring Cowboy in the right place. I confirmed that toggling the port did affect the ports.

iex(4)> MyApp.Web.Endpoint.config(:http)
[
  port: 4001,
  protocol_options: [
    request_timeout: 100000000,
    shutdown_timeout: 100000000,
    idle_timeout: 100000000,
    linger_timeout: 100000000
  ]
]

This is what I see in the IEX console by running iex -S mix phx.server:

Note that there is no stacktrace that tells me what is killing my pry session.

Interactive Elixir (1.10.3) - press Ctrl+C to exit (type h() ENTER for help)
Request to pry #PID<0.718.0> at MyApp.Foo.foo/3 (lib/my_app/foo.ex:16)

   14: 
   15:   def foo(_parent, _args, %{context: %{bar: bar}}) do
   16:     require IEx; IEx.pry
   17: 
   18:     some_code()

Allow? [Yn] <=== I type "Enter"
        
Interactive Elixir (1.10.3) - press Ctrl+C to exit (type h() ENTER for help)
pry(1)> DateTime.utc_now <=== I type this to show when the pry session starts
~U[2020-12-28 06:18:27.861251Z]
** (EXIT from #PID<0.718.0>) shell process exited with reason: shutdown
        
...
        
Interactive Elixir (1.10.3) - press Ctrl+C to exit (type h() ENTER for help)
pry(1)> DateTime.utc_now
~U[2020-12-28 06:18:40.420951Z] <== ~13 seconds, pry session dies
montooner
  • 1,112
  • 4
  • 17
  • 29
  • Please share the full stack trace. – Aleksei Matiushkin Dec 28 '20 at 03:07
  • @AlekseiMatiushkin I updated the original post with the console output, but there isn't any stacktrace unfortunately! That's part of the reason I'm stumped. – montooner Dec 28 '20 at 06:23
  • I don't know much about elixir/pry, but the shell dies because it's linked with the process: since the process exits with `shutdown` (likely the cause of the absence of a stacktrace), it emits the same signal, thus the shell exits with `shutdown`. The process may receive the `shutdown` signal from multiple sources, you can check the origin trapping signals in the process and following the chain. – José M Dec 28 '20 at 12:09

1 Answers1

1

I found the issue: the problem was in a 10s timeout I set in a separate JS project. (haha oops!) I ended up using the Erlang Observer to add a verbose trace on the cowboys_clear and found more inner details about the specific Cowboy error being sent, which led me to realize that the it was initiated from the JS.

Explanation of how the JS (ie client) timeout affected cowboy/Phoenix debugging

The CLIENT would repeatedly close the HTTP connection after 10 seconds, causing Cowboy (which Phoenix is built on) to kill its HTTP stream handler, which in turn would kill the Phoenix IEx.pry session.

This meant that my attempts to increase the Cowboy timeout configurations wouldn't change the kill behavior. My timeouts were being changed but was not being triggered.

How I troubleshot the Cowboy timeout issue via Erlang's :observer

Though my JS issue is project-specific, you may need to dig into the lower-levels of Cowboy from your Phoenix application. These

  1. Run the Phoenix application iex -S mix phx.server
  2. Run :observer.start() to launch Observer GUI
  3. Click on the Applications tab, and look for my Phoenix endpoint (like Elixir.MyApp.Web.Endpoint)
  4. Right-click through its children, clicking on each's Dictionary tab to find one that has an '$initial_call' of cowboy_clear (it was nested 3 levels deep from MyApp.Web.Endpoint)
  5. (Here I was able to confirm that my triggered Pry breakpoints were a descendent from this cowboy_clear node with something like: self |> Process.info |> Keyword.get(:dictionary) |> Keyword.get(:"$ancestors").)
  6. Right-click on the cowboy_clear and select "Trace Process Tree" - I selected all the options.
  7. Change tabs to "Trace Overview", select the pid, and click "Start Trace"
  8. Wait for cowboy to die, and save the trace to a text file
  9. Search for 'exit', 'shutdown', or something like that
  10. In my case, I found 20:57:13:358740 (<0.5984.0>) exit {shutdown,{socket_error,closed,'The socket has been closed.'}}
  11. At this point, I guessed it was JS b/c Cowboy didn't seem to be the one that triggered the request closure

Extra musing: theoretically I would have saved a bunch of time by running my request in GraphiQL or Postman because the timeout didn't exist there.

Useful resources

montooner
  • 1,112
  • 4
  • 17
  • 29